Yeah, it's unfortunate that there's no spec-defined ordering for json keys.

Yeah, it's unfortunate that there's no spec-defined ordering for json keys.

Oh ISTR that the golang json lib we use does have deterministic ordering. But the actual timestamp will land on different indexes on each line, so although it may be deterministic, it's not as simple as the other two where I can just blank out certain byte-indexes.

slog doesn't use the json library to encode records. it does it on its own, and the ordering of keys is different.

slog:
{"time":"2023-10-18T19:25:16.528617+08:00","level":"WARN","msg":"Unclean shutdown detected","booted":"2023-10-16T17:32:38+08:00","age":{}}

ours:
{"age":"3mo3d17h","booted":"2023-07-17T01:52:45+0800","lvl":"warn","msg":"Unclean shutdown detected","t":"2023-10-18T19:25:53.34273+08:00"}

The ordering is different (disregarding the inconsistencies in key names/values which I'm trying to fix).

so doing it this way might be too restrictive for json only b/c of the lack of defined ordering for keys.

so doing it this way might be too restrictive for json only b/c of the lack of defined ordering for keys.

Yes, for json we need something else. On the other hand, json is very well defined. I'm not very worried about it breaking: as long as the json marshaller outputs valid json, there's not a whole lot of things that can go wrong. (it can e..g fail to invoke stringer()-types, but it won't fail to encode a bash escape)

One thing I noticed while doing the log-tests , is that if we use --log.file=/foo/bar, then we pipe logs to both terminal and that file. However: it seems that it's not actually 'dumb copy', what we use is two handlers with identical formatters and different outputs. So each log-invocation causes two records to be formatted individually, effectively doubling the processing overhead.

We could use a custom "both terminal and file" handler like this:

func PipeHandler(fmtr Format, terminal io.Writer, path string) (Handler, error) {
	f, err := os.OpenFile(path, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0644)
	if err != nil {
		return nil, err
	}
	return FuncHandler(func(r *Record) error {
		out := fmtr.Format(r)
		terminal.Write(out)
		_, err := f.Write(out)
		return err
	}), nil
}

But it doesn't seem worth it to optimize the log stuff now, since we're moving to slog later on. Would be nice to use that trick later on though.

The double-output-processing is now fixed in this PR.

Adding this for triage discussion: it adds another command, geth logtest, which might be a tad controversial...

Adding this for triage discussion: it adds another command, geth logtest, which might be a tad controversial...

triage discussion: look into using a build tag, to only add the extra command when run in testing

It's now disabled unless the tag integrationtests is used:

[user@work go-ethereum]$ go run -tags=integrationtests ./cmd/geth --log.format terminal logtest 2>&1  | head
INFO [10-25|12:28:53.656] big.Int                                  111,222,333,444,555,678,999=111,222,333,444,555,678,999
INFO [10-25|12:28:53.656] -big.Int                                 -111,222,333,444,555,678,999=-111,222,333,444,555,678,999
INFO [10-25|12:28:53.656] big.Int                                  11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900
INFO [10-25|12:28:53.656] -big.Int                                 -11,122,233,344,455,567,899,900=-11,122,233,344,455,567,899,900
INFO [10-25|12:28:53.656] uint256                                  111,222,333,444,555,678,999=111,222,333,444,555,678,999
INFO [10-25|12:28:53.656] uint256                                  11,122,233,344,455,567,899,900=11,122,233,344,455,567,899,900
INFO [10-25|12:28:53.656] int64                                    1,000,000=1,000,000
INFO [10-25|12:28:53.656] int64                                    -1,000,000=-1,000,000
INFO [10-25|12:28:53.656] int64                                    9,223,372,036,854,775,807=9,223,372,036,854,775,807
INFO [10-25|12:28:53.656] int64                                    -9,223,372,036,854,775,808=-9,223,372,036,854,775,808
[user@work go-ethereum]$ go run  ./cmd/geth --log.format terminal logtest 2>&1  | head
invalid command: "logtest"
exit status 1

and

[user@work go-ethereum]$ go test ./cmd/geth -tags=integrationtests  -v -run TestLogging
=== RUN   TestLogging
--- PASS: TestLogging (0.10s)
PASS
ok      github.com/ethereum/go-ethereum/cmd/geth        (cached)
[user@work go-ethereum]$ go test ./cmd/geth   -v -run TestLogging
testing: warning: no tests to run
PASS
ok      github.com/ethereum/go-ethereum/cmd/geth        0.081s [no tests to run]

The ordering is different (disregarding the inconsistencies in key names/values which I'm trying to fix).

btw @jwasinger -- I don't think changing t to time is a bad thing, rather it's a good thing. Same with level. However, "age":{}} -- that's not nice at all